Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Packer hangs at provisioning step #13305

Open
jacob-carlborg opened this issue Feb 22, 2025 · 0 comments
Open

Packer hangs at provisioning step #13305

jacob-carlborg opened this issue Feb 22, 2025 · 0 comments
Labels
bug

Comments

@jacob-carlborg
Copy link

Community Note

  • Please vote on this issue by adding a 👍 reaction to the original issue to help the community and maintainers prioritize this request
  • Please do not leave "+1" or other comments that do not add relevant new information or questions, they generate extra noise for issue followers and do not help prioritize the request
  • If you are interested in working on this issue or have submitted a pull request, please leave a comment

When filing a bug, please include the following headings if possible. Any
example text in this template can be deleted.

Overview of the Issue

I'm using Packer and the QEMU builder to build a VM image for Haiku. Packer seems to hang when running the provisioning step. It seems to hang when Packer is running the chmod command to make the provisioning script executable after it has copied the script to the VM. I can manually SSH into the VM at the point when Packer hangs. I can see that it has managed to copy the script to the VM, but it has not been able to make it executable.

I've configured the SSH server to LogLevel DEBUG3. This is the output from the SSH server in the VM after the step: ==> qemu.qemu: Pausing after run of step 'StepConnect'. Press enter to continue.:

AUTH 'sshd'[539]: debug1: fd 9 clearing O_NONBLOCK
AUTH 'sshd'[539]: debug1: Forked child 592.
AUTH 'sshd'[539]: debug3: send_rexec_state: entering fd = 12 config len 3384
AUTH 'sshd'[592]: debug1: rexec start in 9 out 9 newsock 9 pipe 11 sock 12/13
AUTH 'sshd'[539]: debug3: ssh_msg_send: type 0 len 5648
AUTH 'sshd'[539]: debug3: ssh_msg_send: done
AUTH 'sshd'[539]: debug3: send_rexec_state: done
AUTH 'sshd'[539]: debug1: fd 9 clearing O_NONBLOCK
AUTH 'sshd'[539]: debug1: Forked child 593.
AUTH 'sshd'[539]: debug3: send_rexec_state: entering fd = 13 config len 3384
AUTH 'sshd'[593]: debug1: rexec start in 9 out 9 newsock 9 pipe 12 sock 13/14
AUTH 'sshd'[539]: debug3: ssh_msg_send: type 0 len 5648
AUTH 'sshd'[539]: debug3: ssh_msg_send: done
AUTH 'sshd'[539]: debug3: send_rexec_state: done
AUTH 'sshd-session'[592]: debug1: network sockets: 4, 4
AUTH 'sshd-session'[592]: debug3: server_process_channel_timeouts: setting 0 timeouts
AUTH 'sshd-session'[592]: debug3: channel_clear_timeouts: clearing
AUTH 'sshd-session'[592]: Connection from 10.0.2.2 port 61905 on 10.0.2.15 port 22
AUTH 'sshd-session'[592]: debug1: Local version string SSH-2.0-OpenSSH_9.8
AUTH 'sshd-session'[592]: kex_exchange_identification: Connection closed by remote host
AUTH 'sshd-session'[592]: Connection closed by 10.0.2.2 port 61905
AUTH 'sshd'[539]: debug2: server_accept_loop: child 592 for connection from 10.0.2.15 to 10.0.2.2 received config
AUTH 'sshd'[539]: debug1: child_reap: preauth child 592 for connection from 10.0.2.15 to 10.0.2.2 exited with status 255
AUTH 'sshd'[539]: srclimit_penalise: ipv4: new 10.0.2.2/32 deferred penalty of 1 seconds for penalty: connections without attempting authentication
AUTH 'sshd'[539]: debug1: child_close: enter
AUTH 'sshd'[539]: debug2: server_accept_loop: child 593 for connection from 10.0.2.15 to 10.0.2.2 received config
AUTH 'sshd-session'[593]: debug1: network sockets: 4, 4
AUTH 'sshd-session'[593]: debug3: server_process_channel_timeouts: setting 0 timeouts
AUTH 'sshd-session'[593]: debug3: channel_clear_timeouts: clearing
AUTH 'sshd-session'[593]: Connection from 10.0.2.2 port 61906 on 10.0.2.15 port 22
AUTH 'sshd-session'[593]: debug1: Local version string SSH-2.0-OpenSSH_9.8
AUTH 'sshd-session'[593]: debug1: Remote protocol version 2.0, remote software version Go
AUTH 'sshd-session'[593]: debug1: compat_banner: no match: Go
AUTH 'sshd-session'[593]: debug2: fd 4 setting O_NONBLOCK
AUTH 'sshd-session'[593]: debug2: Network child is on pid 594
AUTH 'sshd-session'[593]: debug3: preauth child monitor started
AUTH 'sshd-session'[593]: debug3: privsep user:group 1000:102 [preauth]
AUTH 'sshd-session'[593]: debug1: permanently_set_uid: 1000/102 [preauth]
AUTH 'sshd-session'[593]: debug3: append_hostkey_type: ssh-rsa key not permitted by HostkeyAlgorithms [preauth]
AUTH 'sshd-session'[593]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 20 [preauth]
AUTH 'sshd-session'[593]: debug1: SSH2_MSG_KEXINIT sent [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 20 [preauth]
AUTH 'sshd-session'[593]: debug1: SSH2_MSG_KEXINIT received [preauth]
AUTH 'sshd-session'[593]: debug2: local server KEXINIT proposal [preauth]
AUTH 'sshd-session'[593]: debug2: KEX algorithms: sntrup761x25519-sha512@openssh.com,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-s,kex-strict-s-v00@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
AUTH 'sshd-session'[593]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
AUTH 'sshd-session'[593]: debug2: compression ctos: none,zlib@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: compression stoc: none,zlib@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: languages ctos:  [preauth]
AUTH 'sshd-session'[593]: debug2: languages stoc:  [preauth]
AUTH 'sshd-session'[593]: debug2: first_kex_follows 0  [preauth]
AUTH 'sshd-session'[593]: debug2: reserved 0  [preauth]
AUTH 'sshd-session'[593]: debug2: peer client KEXINIT proposal [preauth]
AUTH 'sshd-session'[593]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c,kex-strict-c-v00@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: host key algorithms: rsa-sha2-256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-256,rsa-sha2-512,ssh-rsa,ssh-dss,ssh-ed25519 [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers ctos: aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers stoc: aes128-gcm@openssh.com,aes256-gcm@openssh.com,chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr [preauth]
AUTH 'sshd-session'[593]: debug2: MACs ctos: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
AUTH 'sshd-session'[593]: debug2: MACs stoc: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96 [preauth]
AUTH 'sshd-session'[593]: debug2: compression ctos: none [preauth]
AUTH 'sshd-session'[593]: debug2: compression stoc: none [preauth]
AUTH 'sshd-session'[593]: debug2: languages ctos:  [preauth]
AUTH 'sshd-session'[593]: debug2: languages stoc:  [preauth]
AUTH 'sshd-session'[593]: debug2: first_kex_follows 0  [preauth]
AUTH 'sshd-session'[593]: debug2: reserved 0  [preauth]
AUTH 'sshd-session'[593]: debug3: kex_choose_conf: will use strict KEX ordering [preauth]
AUTH 'sshd-session'[593]: debug1: kex: algorithm: curve25519-sha256 [preauth]
AUTH 'sshd-session'[593]: debug1: kex: host key algorithm: ecdsa-sha2-nistp256 [preauth]
AUTH 'sshd-session'[593]: debug1: kex: client->server cipher: aes128-gcm@openssh.com MAC: <implicit> compression: none [preauth]
AUTH 'sshd-session'[593]: debug1: kex: server->client cipher: aes128-gcm@openssh.com MAC: <implicit> compression: none [preauth]
AUTH 'sshd-session'[593]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 30 [preauth]
AUTH 'sshd-session'[593]: debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
AUTH 'sshd-session'[593]: debug3: mm_sshkey_sign: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 6 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive_expect: entering, type 7 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: monitor_read: checking request 6
AUTH 'sshd-session'[593]: debug3: mm_answer_sign: entering
AUTH 'sshd-session'[593]: debug3: mm_answer_sign: ecdsa-sha2-nistp256 KEX signature len=101
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 7
AUTH 'sshd-session'[593]: debug2: monitor_read: 6 used once, disabling now
AUTH 'sshd-session'[593]: debug3: send packet: type 31 [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 21 [preauth]
AUTH 'sshd-session'[593]: debug1: ssh_packet_send2_wrapped: resetting send seqnr 3 [preauth]
AUTH 'sshd-session'[593]: debug2: ssh_set_newkeys: mode 1 [preauth]
AUTH 'sshd-session'[593]: debug1: rekey out after 4294967296 blocks [preauth]
AUTH 'sshd-session'[593]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
AUTH 'sshd-session'[593]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 7 [preauth]
AUTH 'sshd-session'[593]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 21 [preauth]
AUTH 'sshd-session'[593]: debug1: ssh_packet_read_poll2: resetting read seqnr 3 [preauth]
AUTH 'sshd-session'[593]: debug1: SSH2_MSG_NEWKEYS received [preauth]
AUTH 'sshd-session'[593]: debug2: ssh_set_newkeys: mode 0 [preauth]
AUTH 'sshd-session'[593]: debug1: rekey in after 4294967296 blocks [preauth]
AUTH 'sshd-session'[593]: debug2: KEX algorithms: sntrup761x25519-sha512@openssh.com,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,ext-info-s,kex-strict-s-v00@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
AUTH 'sshd-session'[593]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
AUTH 'sshd-session'[593]: debug2: compression ctos: none,zlib@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: compression stoc: none,zlib@openssh.com [preauth]
AUTH 'sshd-session'[593]: debug2: languages ctos:  [preauth]
AUTH 'sshd-session'[593]: debug2: languages stoc:  [preauth]
AUTH 'sshd-session'[593]: debug2: first_kex_follows 0  [preauth]
AUTH 'sshd-session'[593]: debug2: reserved 0  [preauth]
AUTH 'sshd-session'[593]: debug1: KEX done [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 5 [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 6 [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 50 [preauth]
AUTH 'sshd-session'[593]: debug1: userauth-request for user user service ssh-connection method none [preauth]
AUTH 'sshd-session'[593]: debug1: attempt 0 failures 0 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_getpwnamallow: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 8 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive_expect: entering, type 9 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: monitor_read: checking request 8
AUTH 'sshd-session'[593]: debug3: mm_answer_pwnamallow: entering
AUTH 'sshd-session'[593]: debug2: parse_server_config_depth: config reprocess config len 3384
AUTH 'sshd-session'[593]: debug3: auth_shadow_acctexpired: today 20141 sp_expire -1 days left -20142
AUTH 'sshd-session'[593]: debug3: account expiration disabled
AUTH 'sshd-session'[593]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 9
AUTH 'sshd-session'[593]: debug2: monitor_read: 8 used once, disabling now
AUTH 'sshd-session'[593]: debug3: server_process_channel_timeouts: setting 0 timeouts [preauth]
AUTH 'sshd-session'[593]: debug3: channel_clear_timeouts: clearing [preauth]
AUTH 'sshd-session'[593]: debug2: input_userauth_request: setting up authctxt for user [preauth]
AUTH 'sshd-session'[593]: debug3: mm_inform_authserv: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 4 [preauth]
AUTH 'sshd-session'[593]: debug2: input_userauth_request: try method none [preauth]
AUTH 'sshd-session'[593]: debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 51 [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 50 [preauth]
AUTH 'sshd-session'[593]: debug1: userauth-request for user user service ssh-connection method publickey [preauth]
AUTH 'sshd-session'[593]: debug1: attempt 1 failures 0 [preauth]
AUTH 'sshd-session'[593]: debug2: input_userauth_request: try method publickey [preauth]
AUTH 'sshd-session'[593]: debug2: userauth_pubkey: valid user user querying public key rsa-sha2-256 AAAAB3NzaC1yc2EAAAADAQABAAACAQDJX2ZQ6F8DtEhAZerAKWF8Vo+1yIP+oEXGRr6IiYU6Dnjmrtc4TOQu4QIR7kSXgEvVtZPSDmWLCeQsytjbokbaYpclNBJ5atPMmWXd13LobUzZHx+kS24nW0TKbLDpImCj8Bmovwgpo2vpfnJyWYz3VLXEdmySW/R1MPm07HB/8CJJUXaha3o0a83fTSc1YDjJj3PDIILE8G0emnhxyxYoMPt+0TswRchs2AC2bVQdEG7hrvmkCe74OHd2FIP/3TDH4OVYfplVxcoRDa/y36WkmXWz/lLROOrjtwXEML2XZDdsGX8B2dcR6ZtoRTJQ02Gj5l0COBP40FhsbDmApsfKAo4hNwqONGVvTiNe1tulBPxDFXWbKKnPCl6/4hLfbfosMLqgBsQ7N/
AUTH 'sshd-session'[593]: debug1: userauth_pubkey: publickey test pkalg rsa-sha2-256 pkblob RSA SHA256:xQiotayM91VPR5nz0J+bOC+83570f+3SHCQbkx3bAYE [preauth]
AUTH 'sshd-session'[593]: debug3: mm_key_allowed: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 22 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive_expect: entering, type 23 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: monitor_read: checking request 4
AUTH 'sshd-session'[593]: debug3: mm_answer_authserv: service=ssh-connection, style=
AUTH 'sshd-session'[593]: debug2: monitor_read: 4 used once, disabling now
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: monitor_read: checking request 22
AUTH 'sshd-session'[593]: debug3: mm_answer_keyallowed: entering
AUTH 'sshd-session'[593]: debug1: temporarily_use_uid: 0/0 (e=0/0)
AUTH 'sshd-session'[593]: debug1: trying public key file /boot/home/config/settings/ssh/authorized_keys
AUTH 'sshd-session'[593]: debug1: Could not open user 'user' authorized keys '/boot/home/config/settings/ssh/authorized_keys': No such file or directory
AUTH 'sshd-session'[593]: debug1: restore_uid: 0/0
AUTH 'sshd-session'[593]: debug3: mm_answer_keyallowed: publickey authentication test: RSA key is not allowed
AUTH 'sshd-session'[593]: Failed publickey for user from 10.0.2.2 port 61906 ssh2: RSA SHA256:xQiotayM91VPR5nz0J+bOC+83570f+3SHCQbkx3bAYE
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 23
AUTH 'sshd-session'[593]: debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-256 [preauth]
AUTH 'sshd-session'[593]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
AUTH 'sshd-session'[593]: debug3: ensure_minimum_time_since: elapsed 4.018ms, delaying 2.223ms (requested 6.241ms) [preauth]
AUTH 'sshd-session'[593]: debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 51 [preauth]
AUTH 'sshd-session'[593]: debug3: receive packet: type 50 [preauth]
AUTH 'sshd-session'[593]: debug1: userauth-request for user user service ssh-connection method password [preauth]
AUTH 'sshd-session'[593]: debug1: attempt 2 failures 1 [preauth]
AUTH 'sshd-session'[593]: debug2: input_userauth_request: try method password [preauth]
AUTH 'sshd-session'[593]: debug3: mm_auth_password: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 12 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive_expect: entering, type 13 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: monitor_read: checking request 12
AUTH 'sshd-session'[593]: debug3: auth_shadow_pwexpired: today 20141 sp_lstchg 1740209571 sp_max -1
AUTH 'sshd-session'[593]: debug3: password expiration disabled
AUTH 'sshd-session'[593]: debug3: mm_answer_authpassword: sending result 1
Last message repeated 1 time
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 13
AUTH 'sshd-session'[593]: Accepted password for user from 10.0.2.2 port 61906 ssh2
AUTH 'sshd-session'[593]: debug1: monitor_child_preauth: user user authenticated by privileged process
AUTH 'sshd-session'[593]: debug3: mm_get_keystate: Waiting for new keys
AUTH 'sshd-session'[593]: debug3: mm_request_receive_expect: entering, type 26
AUTH 'sshd-session'[593]: debug3: mm_request_receive: entering
AUTH 'sshd-session'[593]: debug3: mm_get_keystate: GOT new keys
AUTH 'sshd-session'[593]: debug3: mm_auth_password: user authenticated [preauth]
AUTH 'sshd-session'[593]: debug3: user_specific_delay: user specific delay 0.000ms [preauth]
AUTH 'sshd-session'[593]: debug3: ensure_minimum_time_since: elapsed 176.243ms, delaying 23.472ms (requested 6.241ms) [preauth]
AUTH 'sshd-session'[593]: debug3: send packet: type 52 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_request_send: entering, type 26 [preauth]
AUTH 'sshd-session'[593]: debug3: mm_send_keystate: Finished sending state [preauth]
AUTH 'sshd-session'[593]: debug1: monitor_read_log: child log fd closed
AUTH 'sshd'[539]: debug2: server_accept_loop: child 593 for connection from 10.0.2.15 to 10.0.2.2 auth done
AUTH 'sshd'[539]: debug1: child_close: enter (forcing)
AUTH 'sshd-session'[593]: User child is on pid 595
AUTH 'sshd-session'[595]: debug1: permanently_set_uid: 0/0
AUTH 'sshd-session'[595]: debug3: monitor_apply_keystate: packet_set_state
AUTH 'sshd-session'[595]: debug2: ssh_set_newkeys: mode 0
AUTH 'sshd-session'[595]: debug1: rekey in after 4294967296 blocks
AUTH 'sshd-session'[595]: debug2: ssh_set_newkeys: mode 1
AUTH 'sshd-session'[595]: debug1: rekey out after 4294967296 blocks
AUTH 'sshd-session'[595]: debug1: ssh_packet_set_postauth: called
AUTH 'sshd-session'[595]: debug3: ssh_packet_set_state: done
AUTH 'sshd-session'[595]: debug3: notify_hostkeys: key 0: ssh-rsa SHA256:PaI+e/nP7gK2PozkRIrVP2aB4voAzjhaVXtrYDvcJK0
AUTH 'sshd-session'[595]: debug3: notify_hostkeys: key 1: ecdsa-sha2-nistp256 SHA256:NAoBYh690Jc05dsx6kgrJkhZlJiUxaNGvWnR9Uwke74
AUTH 'sshd-session'[595]: debug3: notify_hostkeys: key 2: ssh-ed25519 SHA256:vXIxPoCOWJ0+slU/L2Gm+y+HcHySkQGpHw5bbn3/lH4
AUTH 'sshd-session'[595]: debug3: notify_hostkeys: sent 3 hostkeys
AUTH 'sshd-session'[595]: debug3: send packet: type 80
AUTH 'sshd-session'[595]: debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
AUTH 'sshd-session'[595]: debug1: Entering interactive session for SSH2.
AUTH 'sshd-session'[595]: debug1: server_init_dispatch
AUTH 'sshd-session'[595]: debug3: receive packet: type 90
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
AUTH 'sshd-session'[595]: debug1: input_session_request
AUTH 'sshd-session'[595]: debug1: channel 0: new session [server-session] (inactive timeout: 0)
AUTH 'sshd-session'[595]: debug2: session_new: allocate (allocated 0 max 10)
AUTH 'sshd-session'[595]: debug3: session_unused: session id 0 unused
AUTH 'sshd-session'[595]: debug1: session_new: session 0
AUTH 'sshd-session'[595]: debug1: session_open: channel 0
AUTH 'sshd-session'[595]: debug1: session_open: session 0: link with channel 0
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: confirm session
AUTH 'sshd-session'[595]: debug3: send packet: type 91
AUTH 'sshd-session'[595]: debug3: receive packet: type 98
AUTH 'sshd-session'[595]: debug1: server_input_channel_req: channel 0 request auth-agent-req@openssh.com reply 1
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 0 channel 0
AUTH 'sshd-session'[595]: debug1: session_input_channel_req: session 0 req auth-agent-req@openssh.com
AUTH 'sshd-session'[595]: debug1: temporarily_use_uid: 0/0 (e=0/0)
AUTH 'sshd-session'[595]: debug1: restore_uid: 0/0
AUTH 'sshd-session'[595]: debug2: fd 6 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug3: fd 6 is O_NONBLOCK
AUTH 'sshd-session'[595]: debug1: channel 1: new auth-listener [auth socket] (inactive timeout: 0)
AUTH 'sshd-session'[595]: debug3: send packet: type 99
AUTH 'sshd-session'[595]: debug3: receive packet: type 97
AUTH 'sshd-session'[595]: debug2: channel 0: rcvd close
AUTH 'sshd-session'[595]: debug2: channel 0: output open -> closed
AUTH 'sshd-session'[595]: debug2: channel 0: input open -> closed
AUTH 'sshd-session'[595]: debug2: channel 0: almost dead
AUTH 'sshd-session'[595]: debug2: channel 0: gc: notify user
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 0 channel 0
AUTH 'sshd-session'[595]: debug1: session_close_by_channel: channel 0 child 0
AUTH 'sshd-session'[595]: Close session: user user from 10.0.2.2 port 61906 id 0
AUTH 'sshd-session'[595]: debug3: session_unused: session id 0 unused
AUTH 'sshd-session'[595]: debug2: channel 0: gc: user detached
AUTH 'sshd-session'[595]: debug2: channel 0: send close
AUTH 'sshd-session'[595]: debug3: send packet: type 97
AUTH 'sshd-session'[595]: debug2: channel 0: is dead
AUTH 'sshd-session'[595]: debug2: channel 0: garbage collecting
AUTH 'sshd-session'[595]: debug1: channel 0: free: server-session, nchannels 2
AUTH 'sshd-session'[595]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t10 [session] r0 i3/0 o3/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1 io 0x00/0x00)\r\n

This is the output from the SSH server in the VM for the next command Packer is performing:

AUTH 'sshd-session'[595]: debug3: receive packet: type 90
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
AUTH 'sshd-session'[595]: debug1: input_session_request
AUTH 'sshd-session'[595]: debug1: channel 0: new session [server-session] (inactive timeout: 0)
AUTH 'sshd-session'[595]: debug1: session_new: session 0
AUTH 'sshd-session'[595]: debug1: session_open: channel 0
AUTH 'sshd-session'[595]: debug1: session_open: session 0: link with channel 0
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: confirm session
AUTH 'sshd-session'[595]: debug3: send packet: type 91
AUTH 'sshd-session'[595]: debug3: receive packet: type 98
AUTH 'sshd-session'[595]: debug1: server_input_channel_req: channel 0 request exec reply 1
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 0 channel 0
AUTH 'sshd-session'[595]: debug1: session_input_channel_req: session 0 req exec
AUTH 'sshd-session'[595]: debug2: channel_set_xtype: labeled channel 0 as session:command (inactive timeout 0)
AUTH 'sshd-session'[595]: Starting session: command for user from 10.0.2.2 port 61906 id 0
AUTH 'sshd-session'[595]: debug2: fd 4 setting TCP_NODELAY
AUTH 'sshd-session'[595]: debug3: set_sock_tos: set socket 4 IP_TOS 0x20
AUTH 'sshd-session'[595]: debug2: fd 10 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug2: fd 9 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug2: fd 12 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug3: send packet: type 99
AUTH 'sshd-session'[596]: debug1: permanently_set_uid: 0/0
AUTH 'sshd-session'[595]: debug2: channel 0: read 31 from efd 12
AUTH 'sshd-session'[595]: debug2: channel 0: rwin 2097151 elen 31 euse 1
AUTH 'sshd-session'[595]: debug2: channel 0: sent ext data 31
AUTH 'sshd-session'[595]: debug2: channel 0: read 39 from efd 12
AUTH 'sshd-session'[595]: debug2: channel 0: rwin 2097119 elen 39 euse 1
AUTH 'sshd-session'[595]: debug2: channel 0: sent ext data 39
AUTH 'sshd-session'[595]: debug3: receive packet: type 96
AUTH 'sshd-session'[595]: debug2: channel 0: rcvd eof
AUTH 'sshd-session'[595]: debug2: channel 0: output open -> drain
AUTH 'sshd-session'[595]: debug2: channel 0: obuf empty
AUTH 'sshd-session'[595]: debug2: chan_shutdown_write: channel 0: (i0 o1 sock -1 wfd 9 efd 12 [read])
AUTH 'sshd-session'[595]: debug2: channel 0: output drain -> closed
AUTH 'sshd-session'[595]: debug1: Received SIGCHLD.
AUTH 'sshd-session'[595]: debug1: session_by_pid: pid 596
AUTH 'sshd-session'[595]: debug2: channel 0: request exit-status confirm 0
AUTH 'sshd-session'[595]: debug3: send packet: type 98
AUTH 'sshd-session'[595]: debug1: session_exit_message: session 0 channel 0 pid 596 exit 0
AUTH 'sshd-session'[595]: debug1: session_exit_message: release channel 0
AUTH 'sshd-session'[595]: debug2: channel 0: read failed rfd 10 maxlen 32768: Broken pipe
AUTH 'sshd-session'[595]: debug2: channel 0: read failed
AUTH 'sshd-session'[595]: debug2: chan_shutdown_read: channel 0: (i0 o3 sock -1 wfd 10 efd 12 [read])
AUTH 'sshd-session'[595]: debug2: channel 0: input open -> drain
AUTH 'sshd-session'[595]: debug2: channel 0: read 0 from efd 12
AUTH 'sshd-session'[595]: debug2: channel 0: closing read-efd 12
AUTH 'sshd-session'[595]: debug2: channel 0: ibuf empty
AUTH 'sshd-session'[595]: debug2: channel 0: send eof
AUTH 'sshd-session'[595]: debug3: send packet: type 96
AUTH 'sshd-session'[595]: debug2: channel 0: input drain -> closed
AUTH 'sshd-session'[595]: debug2: channel 0: send close
AUTH 'sshd-session'[595]: debug3: send packet: type 97
AUTH 'sshd-session'[595]: debug3: channel 0: will not send data after close
AUTH 'sshd-session'[595]: debug3: receive packet: type 97
AUTH 'sshd-session'[595]: debug2: channel 0: rcvd close
AUTH 'sshd-session'[595]: debug3: receive packet: type 90
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
AUTH 'sshd-session'[595]: debug1: input_session_request
AUTH 'sshd-session'[595]: debug1: channel 2: new session [server-session] (inactive timeout: 0)
AUTH 'sshd-session'[595]: debug2: session_new: allocate (allocated 1 max 10)
AUTH 'sshd-session'[595]: debug3: session_unused: session id 1 unused
AUTH 'sshd-session'[595]: debug1: session_new: session 1
AUTH 'sshd-session'[595]: debug1: session_open: channel 2
AUTH 'sshd-session'[595]: debug1: session_open: session 1: link with channel 2
AUTH 'sshd-session'[595]: debug1: server_input_channel_open: confirm session
AUTH 'sshd-session'[595]: debug3: send packet: type 91
AUTH 'sshd-session'[595]: debug3: channel 0: will not send data after close
AUTH 'sshd-session'[595]: debug2: channel 0: is dead
AUTH 'sshd-session'[595]: debug2: channel 0: gc: notify user
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 0 channel 0
AUTH 'sshd-session'[595]: debug1: session_close_by_channel: channel 0 child 0
AUTH 'sshd-session'[595]: Close session: user user from 10.0.2.2 port 61906 id 0
AUTH 'sshd-session'[595]: debug3: session_unused: session id 0 unused
AUTH 'sshd-session'[595]: debug2: channel 0: gc: user detached
AUTH 'sshd-session'[595]: debug2: channel 0: is dead
AUTH 'sshd-session'[595]: debug2: channel 0: garbage collecting
AUTH 'sshd-session'[595]: debug1: channel 0: free: server-session, nchannels 3
AUTH 'sshd-session'[595]: debug3: channel 0: status: The following connections are open:\r\n  #0 server-session (t4 [session:command] r0 i3/0 o3/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1 io 0x00/0x00)\r\n  #2 server-session (t10 [session] r0 i0/0 o0/0 e[closed]/0 fd -1/-1/-1 sock -1 cc -1 io 0x00/0x00)\r\n
AUTH 'sshd-session'[595]: debug3: receive packet: type 98
AUTH 'sshd-session'[595]: debug1: server_input_channel_req: channel 2 request exec reply 1
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 1 channel 2
AUTH 'sshd-session'[595]: debug1: session_input_channel_req: session 1 req exec
AUTH 'sshd-session'[595]: debug2: channel_set_xtype: labeled channel 2 as session:command (inactive timeout 0)
AUTH 'sshd-session'[595]: Starting session: command for user from 10.0.2.2 port 61906 id 1
AUTH 'sshd-session'[595]: debug2: fd 10 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug2: fd 9 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug2: fd 12 setting O_NONBLOCK
AUTH 'sshd-session'[595]: debug3: send packet: type 99
AUTH 'sshd-session'[595]: debug3: receive packet: type 96
AUTH 'sshd-session'[595]: debug2: channel 2: rcvd eof
AUTH 'sshd-session'[595]: debug2: channel 2: output open -> drain
AUTH 'sshd-session'[595]: debug2: channel 2: obuf empty
AUTH 'sshd-session'[595]: debug2: chan_shutdown_write: channel 2: (i0 o1 sock -1 wfd 9 efd 12 [read])
AUTH 'sshd-session'[595]: debug2: channel 2: output drain -> closed
AUTH 'sshd-session'[597]: debug1: permanently_set_uid: 0/0
AUTH 'sshd-session'[595]: debug2: channel 2: read failed rfd 10 maxlen 32768: Broken pipe
AUTH 'sshd-session'[595]: debug2: channel 2: read failed
AUTH 'sshd-session'[595]: debug2: chan_shutdown_read: channel 2: (i0 o3 sock -1 wfd 10 efd 12 [read])
AUTH 'sshd-session'[595]: debug2: channel 2: input open -> drain
AUTH 'sshd-session'[595]: debug2: channel 2: read 0 from efd 12
AUTH 'sshd-session'[595]: debug2: channel 2: closing read-efd 12
AUTH 'sshd-session'[595]: debug2: channel 2: ibuf empty
AUTH 'sshd-session'[595]: debug2: channel 2: send eof
AUTH 'sshd-session'[595]: debug3: send packet: type 96
AUTH 'sshd-session'[595]: debug2: channel 2: input drain -> closed
AUTH 'sshd-session'[595]: debug3: receive packet: type 98
AUTH 'sshd-session'[595]: debug1: server_input_channel_req: channel 2 request keepalive@packer.io reply 1
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 1 channel 2
AUTH 'sshd-session'[595]: debug1: session_input_channel_req: session 1 req keepalive@packer.io
AUTH 'sshd-session'[595]: debug3: send packet: type 100
AUTH 'sshd-session'[595]: debug3: receive packet: type 98
AUTH 'sshd-session'[595]: debug1: server_input_channel_req: channel 2 request keepalive@packer.io reply 1
AUTH 'sshd-session'[595]: debug1: session_by_channel: session 1 channel 2
AUTH 'sshd-session'[595]: debug1: session_input_channel_req: session 1 req keepalive@packer.io
AUTH 'sshd-session'[595]: debug3: send packet: type 100

After that the keepalive@packer.io messages continue and nothing else happens.

Reproduction Steps

  1. Clone the the https://github.com/cross-platform-actions/haiku-builder repository
  2. Checkout the 05c79a3923a8eb678f6cf8300ba63bfc0f8f6fed commit
  3. Run the following command:
PACKER_LOG=1 packer build -var os_version=r1beta5 -var-file var_files/common.pkrvars.hcl -var-file var_files/x86-64.pkrvars.hcl -var-file var_files/r1beta5/x86-64.pkrvars.hcl -force main.pkr.hcl

Packer version

Packer v1.12.0

Simplified Packer Template

https://github.com/cross-platform-actions/haiku-builder/blob/05c79a3923a8eb678f6cf8300ba63bfc0f8f6fed/main.pkr.hcl

Operating system and Environment details

Host information

$ sw_vers
ProductName:		macOS
ProductVersion:		15.3
BuildVersion:		24D60
$ uname -a
Darwin MacBook-Pro.local 24.3.0 Darwin Kernel Version 24.3.0: Thu Jan  2 20:24:06 PST 2025; root:xnu-11215.81.4~3/RELEASE_ARM64_T8103 arm64

Guest information

Operation system: Haiku
Version: r1beta5
Architecture: x86-64
ISO URL: http://mirror.rit.edu/haiku/r1beta5/haiku-r1beta5-x86_64-anyboot.iso

Log Fragments and crash.log files

This is the last few lines of the output of Packer before it hangs:

==> qemu.qemu: Pausing after run of step 'stepTypeBootCommand'. Press enter to continue.
    qemu.qemu: Not using a NetBridge -- skipping StepWaitGuestAddress
==> qemu.qemu: Pausing after run of step 'stepWaitGuestAddress'. Press enter to continue.
==> qemu.qemu: Using SSH communicator to connect: 127.0.0.1
==> qemu.qemu: Waiting for SSH to become available...
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [INFO] Waiting for SSH, up to timeout: 2h46m40s
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [INFO] Attempting SSH connection to 127.0.0.1:4419...
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [DEBUG] reconnecting to TCP connection for SSH
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [DEBUG] handshaking with SSH
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [DEBUG] handshake complete!
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [DEBUG] Opening new ssh session
2025/02/22 08:36:17 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:36:17 [INFO] agent forwarding enabled
==> qemu.qemu: Connected to SSH!
==> qemu.qemu: Pausing after run of step 'StepConnect'. Press enter to continue.
2025/02/22 08:37:19 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:19 Running the provision hook
2025/02/22 08:37:19 [INFO] (telemetry) Starting provisioner shell
==> qemu.qemu: Pausing before the next provisioner . Press enter to continue.
2025/02/22 08:37:25 packer-provisioner-shell plugin: [DEBUG] - common: sending ConfigSpec as protobuf
2025/02/22 08:37:25 [DEBUG] - common: receiving ConfigSpec as protobuf
==> qemu.qemu: Provisioning with shell script: resources/provision.sh
2025/02/22 08:37:25 packer-provisioner-shell plugin: Opening resources/provision.sh for reading
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Opening new ssh session
2025/02/22 08:37:25 packer-provisioner-shell plugin: [INFO] 156 bytes written for 'uploadData'
2025/02/22 08:37:25 [INFO] 156 bytes written for 'uploadData'
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Starting remote scp process:  scp -vt /tmp
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Started SCP session, beginning transfers...
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Copying input data into temporary file so we can read the length
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] scp: Uploading script_2280.sh: perms=C0644 size=156
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] SCP session complete, closing stdin pipe.
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Waiting for SSH session to complete.
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] scp stderr (length 70): Sink: C0644 156 script_2280.sh
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: scp: debug1: fd 0 clearing O_NONBLOCK
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] Opening new ssh session
2025/02/22 08:37:25 packer-plugin-qemu_v1.1.1_x5.0_darwin_arm64 plugin: 2025/02/22 08:37:25 [DEBUG] starting remote command: chmod 0755 /tmp/script_2280.sh

After the above last line there is no more output from Packer.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jacob-carlborg