dartfn-generated project fails tests locally

[redbrogdon]

I just tried creating a project with dartfn, and I can't get the generated code to pass its included tests:

~/source/hellow> dartfn generate helloworld
project: hellow
Creating helloworld application `hellow`:
  /Users/redbrogdon/source/hellow/.gitignore
  /Users/redbrogdon/source/hellow/Dockerfile
  /Users/redbrogdon/source/hellow/Makefile
  /Users/redbrogdon/source/hellow/README.md
  /Users/redbrogdon/source/hellow/analysis_options.yaml
  /Users/redbrogdon/source/hellow/bin/server.dart
  /Users/redbrogdon/source/hellow/lib/functions.dart
  /Users/redbrogdon/source/hellow/pubspec.yaml
  /Users/redbrogdon/source/hellow/test/function_test.dart
9 files written.

--> to provision required packages, run 'pub get'

~/source/hellow> dart pub get
Resolving dependencies... (1.3s)
+ _fe_analyzer_shared 29.0.0
+ analyzer 2.6.0
+ args 2.3.0
+ async 2.8.2
+ boolean_selector 2.1.0
+ build 2.1.1
+ build_config 1.0.0
+ build_daemon 3.0.1
+ build_resolvers 2.0.4
+ build_runner 2.1.4
+ build_runner_core 7.2.2
+ built_collection 5.1.1
+ built_value 8.1.2
+ charcode 1.3.1
+ checked_yaml 2.0.1
+ cli_util 0.3.5
+ code_builder 4.1.0
+ collection 1.15.0
+ convert 3.0.1
+ coverage 1.0.3
+ crypto 3.0.1
+ dart_style 2.2.0
+ file 6.1.2
+ fixnum 1.0.0
+ frontend_server_client 2.1.2
+ functions_framework 0.4.1
+ functions_framework_builder 0.4.4
+ glob 2.0.2
+ graphs 2.1.0
+ http 0.13.4
+ http_multi_server 3.0.1
+ http_parser 4.0.0
+ io 1.0.3
+ js 0.6.3
+ json_annotation 4.3.0
+ logging 1.0.2
+ matcher 0.12.11
+ meta 1.7.0
+ mime 1.0.0
+ node_preamble 2.0.1
+ package_config 2.0.2
+ path 1.8.0
+ pool 1.5.0
+ pub_semver 2.1.0
+ pubspec_parse 1.1.0
+ shelf 1.2.0
+ shelf_packages_handler 3.0.0
+ shelf_static 1.1.0
+ shelf_web_socket 1.0.1
+ source_gen 1.1.1
+ source_helper 1.3.0
+ source_map_stack_trace 2.1.0
+ source_maps 0.10.10
+ source_span 1.8.1
+ stack_trace 1.10.0
+ stream_channel 2.1.0
+ stream_transform 2.0.0
+ string_scanner 1.1.0
+ term_glyph 1.2.0
+ test 1.18.2
+ test_api 0.4.5
+ test_core 0.4.5
+ test_process 2.0.2
+ timing 1.0.0
+ typed_data 1.3.0
+ vm_service 7.3.0
+ watcher 1.0.1
+ web_socket_channel 2.1.0
+ webkit_inspection_protocol 1.0.0
+ yaml 3.1.0
Changed 70 dependencies!

~/source/hellow> dart test --chain-stack-traces
Building package executable... (5.1s)
Built test:test.
00:02 +0 -1: test/function_test.dart: defaults [E]
  Expected: <0>
    Actual: <-15>
  Process `dart bin/server.dart` had an unexpected exit code.

  package:test_api                              expect
  package:test_process/test_process.dart 228:5  TestProcess.shouldExit


Process `dart bin/server.dart` exited with exitCode -15. Output:
    Listening on :8080
    2021-10-16T15:58:22.530506  0:00:00.005658 GET     [200] /
00:02 +0 -1: Some tests failed.

Any idea what might be going wrong for me? Have I missed a step somewhere?

My Dart version is:

Dart SDK version: 2.14.4 (stable) (Wed Oct 13 11:11:32 2021 +0200) on "macos_x64"

[redbrogdon]

CC: @kevmoo.

[kevmoo]

Do you already have a server running on your machine @ 8080?

Guessing that's it!

[redbrogdon]

I don't believe that's the cause of the initial failure. If I run the tests a second time, though, I do get that error:

00:01 +0 -1: test/function_test.dart: defaults [E]
  Expected: should eventually emit an event that 'Listening on :8080'
    Actual: <Instance of 'StreamQueue<String>'>
     Which: emitted x Stream closed.
              which never did emit an event that 'Listening on :8080'

  package:test_api               expectLater
  test/function_test.dart 13:11  main.<fn>
  ===== asynchronous gap ===========================
  dart:async                     _asyncThenWrapperHelper
  test/function_test.dart        main.<fn>


Process `dart bin/server.dart` exited with exitCode 255. Output:
[e] Unhandled exception:
[e] SocketException: Failed to create server socket (OS Error: Address already in use, errno = 48), address = 0.0.0.0, port = 8080
[e] #0      _NativeSocket.bind (dart:io-patch/socket_patch.dart:962:7)
[e] <asynchronous suspension>
[e] #1      serve (package:shelf/shelf_io.dart:50:16)
[e] <asynchronous suspension>
[e] #2      run (package:functions_framework/src/run.dart:32:18)
[e] <asynchronous suspension>
[e] #3      _serve (package:functions_framework/serve.dart:127:3)
[e] <asynchronous suspension>
[e] #4      serve (package:functions_framework/serve.dart:53:5)
[e] <asynchronous suspension>
[e] #5      main (file:///Users/redbrogdon/source/hellow/bin/server.dart:20:3)
[e] <asynchronous suspension>
00:01 +0 -1: Some tests failed.

I believe the dart bin/server.dart process initiated in the first run is hanging out in memory -- If I kill it manually, I can get back to the first error.

[kevmoo]

That's 🍌 🍌 . Hrm...

[kevmoo]

Glad you're trying this out!

[jakub-trzebiatowski]

So? I've just created a project with the helloworld template and I confirm that dart test is failing out-of-the-box. That sounds very worrying; does it mean that there's a problem with the test, or maybe the function doesn't work at all?

[jakub-trzebiatowski]

@kevmoo

Do you already have a server running on your machine @ 8080?

Guessing that's it!

I cannot see in this section of the quickstart that it's required to manually start the server before running dart test. Is it required?

[jakub-trzebiatowski]

My output of running dart test:

backend ✔                                                                                                                                                                       33m  ⍉
▶ dart test
00:01 +0 -1: test/function_test.dart: defaults [E]
  Expected: <0>
    Actual: <-15>
  Process `dart bin/server.dart` had an unexpected exit code.

  package:test_api                              expect
  package:test_process/test_process.dart 228:5  TestProcess.shouldExit
  ===== asynchronous gap ===========================
  test/function_test.dart 28:5                  main.<fn>


Process `dart bin/server.dart` exited with exitCode -15. Output:
    Listening on :8080
    2021-12-23T11:49:26.447544  0:00:00.005582 GET     [200] /
00:01 +0 -1: Some tests failed.

Consider enabling the flag chain-stack-traces to receive more detailed exceptions.
For example, 'dart test --chain-stack-traces'.

backend ✔                                                                                                                                                                       33m  ⍉
▶ lsof -i tcp:8080
COMMAND   PID  USER   FD   TYPE             DEVICE SIZE/OFF NODE NAME
dart    85133 jakub   12u  IPv4 0x6f20cda13ac1c289      0t0  TCP *:http-alt (LISTEN)

So it seems that the function_test.dart correctly starts the server process, it starts listening on the correct port, but for some reason the line...

 proc.signal(ProcessSignal.sigterm);

...doesn't work as expected and doesn't stop the process. What bothers me is the -15 exit code. I'm not a great expert on *nix systems, but where could this exit code come from, if lsof proves that the launched process never exited?

I've just checked, and the -15 exit code correspond to SIGTERM, which has signal id = 15.

From Process.exitCode docs:

If the process was terminated due to a signal the exit code will be a negative value in the range [-255..-1], where the absolute value of the exit code is the signal number.

It seems that it's expected that the exit code will be -15 if we send the sigterm to the process.

So the only mistery is why the server process, from one perspective, seems to exit with the (proper) -15 exit code, but on the other hand seems to be still alive and blocking the port.

[saviobatista]

Would be awesome if we got this solved, what I could do to help was trying every single ProccessSignal const and did it. All of the maintain that process active and I had to do a lsof -i tcp:8080 then kill PID, so here is a list of each signal sent and code return at macOS Monterey (12.1) M1 2020 on a direct git clone https://github.com/GoogleCloudPlatform/functions-framework-dart.git then dart test test/function_test.dart:

proc.signal(ProcessSignal.sigterm);
RESULT: -15
proc.signal(ProcessSignal.sighup);
-1
proc.signal(ProcessSignal.sigint);
-9
proc.signal(ProcessSignal.sigquit);
-9
proc.signal(ProcessSignal.sigill);
-4
proc.signal(ProcessSignal.sigtrap);
-5
proc.signal(ProcessSignal.sigabrt);
-6
proc.signal(ProcessSignal.sigbus);
-10
proc.signal(ProcessSignal.sigfpe);
-8
proc.signal(ProcessSignal.sigkill);
-9
proc.signal(ProcessSignal.sigusr1);
-30
proc.signal(ProcessSignal.sigsegv);
-11
proc.signal(ProcessSignal.sigusr2);
-31
proc.signal(ProcessSignal.sigpipe);
-9
proc.signal(ProcessSignal.sigalrm);
-14
proc.signal(ProcessSignal.sigterm);
-15
proc.signal(ProcessSignal.sigchld);
-9
proc.signal(ProcessSignal.sigcont);
-9
proc.signal(ProcessSignal.sigstop);
-9
proc.signal(ProcessSignal.sigtstp);
-9
proc.signal(ProcessSignal.sigttin);
-9
proc.signal(ProcessSignal.sigttou);
-9
proc.signal(ProcessSignal.sigurg);
-9
proc.signal(ProcessSignal.sigxcpu);
-24
proc.signal(ProcessSignal.sigxfsz);
-25
proc.signal(ProcessSignal.sigvtalrm);
-26
proc.signal(ProcessSignal.sigprof);
-27
proc.signal(ProcessSignal.sigwinch);
-9
proc.signal(ProcessSignal.sigpoll);
-9
proc.signal(ProcessSignal.sigsys);
-12

I think this might be related to package test_process about file test_process.dart#L205 which says that TestProcess.Signal is not supported in Windows, this might be not supported by macOS also.

EDIT:
Just found that before sending sigterm I've put a print(proc.pid); which shows PID of dart bin/server.dart, but it's different from after error what we got at lsof -i tcp:8080 that means server.dart is creating a secondary process to listen but it is not dealing with that process when sending signal to end.